add logging for upload queue processing (WP-1014) - #629
add logging for upload queue processing (WP-1014)#629vsolovei-smartling wants to merge 10 commits into
Conversation
Queue rows were deleted the moment they were handed to the upload job, before the upload itself was attempted. Any fatal error, timeout or out of memory during the upload that followed destroyed the queued work with no trace: the submission stayed New, with no queue row, no last_error and no log line. Rows are now claimed instead of deleted, and removed only once the upload has been accounted for. A run that dies mid-upload leaves the claim behind, and the row becomes eligible again after a staleness timeout. Claims are counted, and once they are exhausted the submissions are failed with a visible error rather than retried forever. The two paths that dropped a whole queue item when a submission or its target locale could not be resolved did so silently; they now log which submission was responsible. Throttled cron runs logged nothing at all and now log a reason. Separately, shutdownHandler treated any error type outside a blacklist as a fatal, and the blacklist covered E_DEPRECATED but not E_USER_DEPRECATED. Since error_get_last() returns the last error of any severity, a single Guzzle deprecation was reported as "Wordpress is down" on nearly every request: one customer log held 2509 such false emergencies hiding one real E_PARSE. The check is now a whitelist of request-terminating types, and the error type is named instead of a decimal printed behind an "0x" prefix. Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com>
…ently (WP-1014) Code review on PR #629 found that the "cleanup" commit had silently reverted DebugTrait::shutdownHandler back to its original buggy blacklist implementation and deleted its test file, undoing the false-fatal-report fix described in the PR itself. Restored both from the original fix commit. Also fixes upload queue review finding: when a queue row groups submissions for the same content across multiple target locales and one submission's locale can no longer be resolved, the whole row was deleted but only logged - resolved sibling submissions were left in New status with no queue row and no error. dequeue() now keeps checking every submission in the group instead of stopping at the first failure, and sets a visible error message on every submission that still exists once the group is discarded.
- UploadJob: catch \Throwable (not just \Exception) around the upload dispatch, matching processCloning() and actually delivering the crash-resilience this queue rework is meant to provide. - UploadJob: complete() the claimed queue item when no active profile is found, instead of leaving it claimed until it's retried into a misleading "terminated unexpectedly" failure. - UploadJob: processCloning() now dispatches through WordpressFunctionProxyHelper::do_action(), matching processUploadQueue() and making it mockable in tests. - UploadQueueManager: build the stale-claim WHERE fragment via ConditionBlock/Condition instead of raw sprintf ordinals, and extract the duplicated fail-and-delete logic into discardQueueItem(). - SubmissionUploadTest: complete() dequeued items in the drain loop, since dequeue() now claims rows instead of deleting them and count() no longer drops on its own. - Add UploadJobTest coverage for the \Throwable catch, the no-active-profile completion, and the proxied cloning dispatch. Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com>
… (WP-1014) - UploadJob::processUploadQueue() now catches failures from getOrCreateJobInfoForDailyBucketJob(), matching the crash-safety pattern already used for the settings profile lookup: log, record the error on the submission, complete the queue item, and continue instead of leaving the claimed row stuck and aborting the cron run. - DebugTrait declared FATAL_ERROR_TYPES/ERROR_TYPE_NAMES as trait constants, which PHP only allows from 8.2 onward, causing "Traits cannot have constants" fatal errors on this project's target PHP 8.0. Converted both to private static methods.
…lure (WP-1014) processUploadQueue() only logged/errored the first submission in a queue item when the profile lookup or daily bucket job creation failed, then deleted the whole row. Any sibling submission grouped in the same item (same content, other target locale) vanished silently: no error, no log line, stuck in New forever. Both catch blocks now loop over every submission in the item. Migration260825's ADD COLUMN also failed for any site still on a schema version below 240315: Migration240315 recreates the table with CREATE TABLE IF NOT EXISTS from the live, current UploadQueueEntity::getFieldDefinitions(), which already includes the new claimed/attempts columns, so the later unconditional ALTER TABLE hit a duplicate-column error and never recorded itself as applied. The migration now checks SHOW COLUMNS first and only adds what's actually missing. Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com>
PavelLoparev
left a comment
There was a problem hiding this comment.
Automated review for WP-1014. Despite the PR title ("add logging"), this is a genuine root-cause fix: claiming queue rows via claimed/attempts (Migration260825) instead of deleting them up front, and catching \Throwable (not just \Exception) around the upload dispatch, directly addresses the reported symptom (assets failing to upload most of the time due to a crash/timeout silently destroying the queue row with no retry). Well covered by new tests overall.
Two cross-cutting points not tied to a single line:
- No DB index covers the
claimedcolumn (UploadQueueEntity::getIndexes()only has the primary key).dequeue()'s stale-claim filter (q.claimed IS NULL OR q.claimed < threshold) will full-scan as the queue grows, which matters given the reported symptom is a backed-up queue. Migration260825.phphas real conditional logic (only adds columns that don't already exist) but no unit test, unlike most other recently-touched files in this PR.
Ready to merge? With fixes — see inline comments below. The unchecked claim()/delete() results create a duplicate-processing/infinite-loop risk in exactly the failure paths this PR is meant to harden.
|
|
||
| private function claim(int $id, int $attempts): void | ||
| { | ||
| $this->db->query(QueryBuilder::buildUpdateQuery( |
There was a problem hiding this comment.
🟡 warning — claim()'s $this->db->query() result is never checked. If this UPDATE silently fails (lock timeout, connection blip), the row is never actually marked claimed, so a concurrent dequeue() call can pick up the same row again while it's already being processed → duplicate upload to Smartling, which is the exact bug class this PR is trying to fix.
Suggested fix: return whether the update affected a row, and have dequeue() continue (skip/retry) instead of returning the item when the claim fails:
private function claim(int $id, int $attempts): bool
{
return (bool)$this->db->query(QueryBuilder::buildUpdateQuery(
$this->tableName,
[...],
$this->idCondition($id),
));
}This also doubles as a fix for the non-atomic claim (SELECT then separate UPDATE with no row locking) — checking affected-row count on a conditional WHERE id=? AND (claimed IS NULL OR claimed < ?) update would catch a lost race.
There was a problem hiding this comment.
Added return
|
|
||
| private function delete(int $id): void | ||
| { | ||
| $this->db->query(QueryBuilder::buildDeleteQuery($this->tableName, $this->idCondition($id))); |
There was a problem hiding this comment.
🟡 warning — Same unchecked-query() issue as claim(). This delete() is called from discardQueueItem() (line 142), which is invoked inside dequeue()'s while loop for unprocessable rows. If the delete silently fails, the loop's continue re-runs the same SELECT and gets back the same row forever — an infinite loop inside a single dequeue() call. Worth checking the affected-row count and breaking/logging if the delete didn't remove the row.
There was a problem hiding this comment.
Added return
| $this->getLogger()->notice("Skipping upload of submissionId={$itemSubmission->getId()}: $message"); | ||
| $this->submissionManager->setErrorMessage($itemSubmission, $message); | ||
| } | ||
| $this->uploadQueueManager->complete($item); |
There was a problem hiding this comment.
🟡 warning / 🟣 question — This branch calls complete($item) and permanently discards the item on the very first "no active profile" failure, bypassing the new claim/attempts/stale-retry mechanism entirely. Is this intentional (treating a missing profile as a permanent configuration error rather than transient)? If getSingleSettingsProfile can ever fail transiently (e.g. DB blip), this item is lost with no retry, unlike a hard crash further down which now gets up to MAX_ATTEMPTS retries.
There was a problem hiding this comment.
As intended
| $this->getLogger()->notice("Skipping upload of submissionId={$itemSubmission->getId()}: failed to get or create daily bucket job: {$e->getMessage()}"); | ||
| $this->submissionManager->setErrorMessage($itemSubmission, $e->getMessage()); | ||
| } | ||
| $this->uploadQueueManager->complete($item); |
There was a problem hiding this comment.
🟡 warning / 🟣 question — Same pattern: a failure from getOrCreateJobInfoForDailyBucketJob (an API/network call — exactly the kind of intermittent failure that could explain "unable to upload most of the time") immediately calls complete($item) and permanently drops the submission, instead of leaving it claimed so it flows through the same stale-claim retry path as a crash in the do_action call below. Please confirm this is meant to be non-retryable, or consider not calling complete() here so it gets retried.
There was a problem hiding this comment.
As intended
| return DateTimeHelper::dateTimeToString( | ||
| (new \DateTime('now', new \DateTimeZone(DateTimeHelper::TIMEZONE_UTC))) | ||
| ->modify('-' . self::STALE_CLAIM_SECONDS . ' seconds') | ||
| ); |
There was a problem hiding this comment.
🔵 suggestion — getStaleClaimThreshold() builds its own new \DateTimeZone(DateTimeHelper::TIMEZONE_UTC) explicitly, while claim() (below) stores the claim time via DateTimeHelper::nowAsString(), which uses DateTimeHelper::getDefaultTimezone() — UTC only because nothing currently overrides it. These two time sources aren't structurally guaranteed to agree. Consider computing both via the same helper so a future change to the default timezone can't silently desync staleness detection from claim timestamps.
There was a problem hiding this comment.
Synchronized
…loned submissions still uploaded (WP-1014) - UploadQueueManager::dequeue(): wrap per-submission resolution in a try/catch(\Throwable). claim() runs after resolution, so any exception besides the already-handled SmartlingDbException left the row completely unclaimed forever, re-thrown on every future dequeue() call and blocking the rest of the per-blog queue from ever being processed. It's now treated like the existing missing-submission/unresolvable-locale cases: logged and discarded with a visible error. - UploadQueueManager::getStaleClaimThreshold(): source "now" from DateTimeHelper::getDefaultTimezone() instead of a separately hardcoded UTC, so it can't desync from claim()'s DateTimeHelper::nowAsString(). - UploadQueueManager::dequeue(): drop the redundant $submissions array, which was always identical to $existingSubmissions by the time it was used. - UploadJob::processUploadQueue(): isCloned() logged "skipping" but never skipped, uploading cloned submissions same as any other. Added the missing complete()+continue. - UploadJob: extract the three copy-pasted "fail every submission in the item" blocks into failItem(), fixing the do_action-catch block's variable shadowing of the outer $submission along the way. - UploadQueueManagerTest::testDequeue(): restore coverage of the locate()/left() join clause that extracts the first submission id from a group, lost when the exact-SQL assertEquals was loosened to assertStringContainsString (necessary since the query now embeds a wall-clock-dependent stale-claim timestamp). - Add tests: dequeue() discarding a row when resolution throws an unexpected exception, and UploadJob skipping cloned submissions. Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com>
…(WP-1014) PR #629 review comment (PavelLoparev, 3863741398): delete()'s $this->db->query() result was never checked. wpdb::query() returns false on failure (deadlock, lock-wait timeout, connection blip) without throwing, so a failed DELETE inside discardQueueItem() went unnoticed: dequeue()'s while loop would continue, re-select the exact same still-present row, and discard it again - spinning on it forever within a single dequeue() call. - delete() now returns bool. - discardQueueItem() returns bool and logs when the delete didn't happen; both call sites in dequeue() return null instead of continuing the loop when a discard fails to actually remove the row. - complete() logs (but doesn't otherwise react) on a failed delete: the row simply stays claimed and is picked up by the existing stale-claim retry path, so no special handling is needed there beyond visibility. Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com>
PR #629 review comment (PavelLoparev, 3863741379): claim()'s $this->db->query() result was never checked. wpdb::query() returns false on failure without throwing, so a silently failed claim let dequeue() hand out an UploadQueueItem whose row a second dequeue($blogId) call was still free to claim - dispatching the same content for translation twice. claim() now returns bool; dequeue() returns null instead of returning the item when the claim can't be confirmed. Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com>
No description provided.